search

freeacs / freeacs

Free TR-069 ACS that can run (mostly) anywhere.
https://github.com/freeacs/freeacs/wiki
MIT License
146 stars 84 forks source link

Docker Error Monitor/STUN #197

Closed penaivanalejandro closed 5 years ago

penaivanalejandro commented 5 years ago

When I finish installing FreeACS with Docker and verify the services it shows the following:

This is the Monitor LOG:

monitor_1     | 2018-10-12 00:01:08 [Thread-576] INFO  c.o.x.monitor.task.MonitorExecution - Monitoring: MonitorExecution: URL http://stun:8080/stun/ok has status ERROR, error is ERROR: Server did not start properly :java.sql.SQLNonTransientConnectionException: Could not create connection to database server. Attempted reconnect 3 times. Giving up.<br>
monitor_1     | com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:108)<br>com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:95)<br>com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:87)<br>com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:61)<br>com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:71)<br>com.mysql.cj.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:932)<br>com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:857)<br>com.mysql.cj.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:444)<br>com.mysql.cj.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:230)<br>com.mysql.cj.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:226)<br>com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:117)<br>com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:123)<br>com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:367)<br>com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:196)<br>com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:467)<br>com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:541)<br>com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:115)<br>com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:112)<br>com.github.freeacs.dbi.util.ACSVersionCheck.versionCheck(ACSVersionCheck.java:50)<br>com.github.freeacs.dbi.Users.<init>(Users.java:45)<br>com.github.freeacs.stun.StunServlet.initializeDBI(StunServlet.java:66)<br>com.github.freeacs.stun.StunServlet.trigger(StunServlet.java:75)<br>com.github.freeacs.stun.StunServlet.init(StunServlet.java:50)<br>javax.servlet.GenericServlet.init(GenericServlet.java:244)<br>org.eclipse.jetty.servlet.ServletHolder.initServlet(ServletHolder.java:670)<br>org.eclipse.jetty.servlet.ServletHolder.initialize(ServletHolder.java:427)<br>org.eclipse.jetty.servlet.ServletHandler.initialize(ServletHandler.java:760)<br>org.springframework.boot.web.embedded.jetty.JettyEmbeddedWebAppContext$JettyEmbeddedServletHandler.deferredInitialize(JettyEmbeddedWebAppContext.java:46)<br>org.springframework.boot.web.embedded.jetty.JettyEmbeddedWebAppContext.deferredInitialize(JettyEmbeddedWebAppContext.java:36)<br>org.springframework.boot.web.embedded.jetty.JettyWebServer.handleDeferredInitialize(JettyWebServer.java:209)<br>org.springframework.boot.web.embedded.jetty.JettyWebServer.start(JettyWebServer.java:141)<br>org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.startWebServer(ServletWebServerApplicationContext.java:300)<br>org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.finishRefresh(ServletWebServerApplicationContext.java:162)<br>org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:553)<br>org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:140)<br>org.springframework.boot.SpringApplication.refresh(SpringApplication.java:759)<br>org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:395)<br>org.springframework.boot.SpringApplication.run(SpringApplication.java:327)<br>org.springframework.boot.SpringApplication.run(SpringApplication.java:1255)<br>org.springframework.boot.SpringApplication.run(SpringApplication.java:1243)<br>com.github.freeacs.stun.App.main(App.java:22)<br>
monitor_1     |

In the webpage show this status:

docker_stun

penaivanalejandro commented 5 years ago

I realize that a new installation with the command:

wget https://raw.githubusercontent.com/freeacs/freeacs/master/scripts/docker-compose.yml && wget https://raw.githubusercontent.com/freeacs/freeacs/master/scripts/.env && docker-compose -p freeacs up -d

Send error about the Monitor service, when I restart or reinstall with the commands:

docker-compose -p freeacs pull & & docker-compose -p freeacs down & & docker-compose -p freeacs up -d

or docker-compose -p freeacs restart

The Monitor service works. But I realize that the service of TR069 is not up, shows the following when consulting the website:

dockertr069

But adding the slash "ok" shows the following legend:

dockertr069_ok

jarlah commented 5 years ago

Stun should work. Containers will take some time to boot properly the first time due to mysql container. About tr069 i have removed the information screen for tr069, you can not get the provision servlet in browser any more. In addition i have changed the provision url napping from /tr069/ to /tr069/prov.

penaivanalejandro commented 5 years ago

Hi... I add the URL you tell me on the ONT 7259G (UnitType)...

And now have this error in the log (All this are in docker):

tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-17837] DEBUG c.g.freeacs.tr069.HTTPReqResData - Sessionid node01tcqz6nm974yo5ptfsu92jkg676 did not return a SessionData object from cache, must create a new SessionData object
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-17837] DEBUG c.g.freeacs.tr069.HTTPReqResData - Sessionid node01tcqz6nm974yo5ptfsu92jkg676 created: 1539355446210, lastAccess:1539355446210, mxInactiveInterval:-1
tr069_1       | 2018-10-12 09:44:06 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Cache.Cleanup.run() starts
tr069_1       | Exception in thread "Cache Cleanup" java.util.ConcurrentModificationException
tr069_1       |         at java.util.Hashtable$Enumerator.next(Hashtable.java:1387)
tr069_1       |         at com.github.freeacs.common.util.Cache$Cleanup.run(Cache.java:59)
tr069_1       |         at java.lang.Thread.run(Thread.java:748)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-17837] DEBUG c.g.freeacs.tr069.HTTPReqResData - Adding a HTTPReqResData object to the list
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-17837] INFO  c.g.f.base.http.BasicAuthenticator - Send challenge to CPE, located on IP-address 172.20.0.10
tr069_1       | 2018-10-12 09:44:06 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Key node0m1urmtoag2tzueharz5abf8f70SESSION with CacheValue com.github.freeacs.common.util.CacheValue@2bf5f8c5 is to be removed
tr069_1       | 2018-10-12 09:44:06 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - CacheValue has a cleanupnotifier-class which will be executed
tr069_1       | 2018-10-12 09:44:06 [Cache Cleanup] ERROR c.g.f.base.SessionDataCacheCleanup - SessionData for null (key:node0m1urmtoag2tzueharz5abf8f70) was removed from cache after timeout - indicate a session which did not terminate correctly
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.freeacs.tr069.HTTPReqResData - Sessionid node015fq3gch221uu1ged3e2cxkhfp77 did not return a SessionData object from cache, must create a new SessionData object
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.freeacs.tr069.HTTPReqResData - Sessionid node015fq3gch221uu1ged3e2cxkhfp77 created: 1539355446285, lastAccess:1539355446285, mxInactiveInterval:-1
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.freeacs.tr069.HTTPReqResData - Adding a HTTPReqResData object to the list
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.f.base.http.BasicAuthenticator - Basic verification of CPE starts, located on IP-address 172.20.0.10
tr069_1       | 2018-10-12 09:44:06 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Cache.Cleanup.run() starts
tr069_1       | 2018-10-12 09:44:06 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Cache removed 0 elements out of 0 in 0 ms.
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.f.base.http.DigestAuthenticator - Basic verification identifed unit id IPHO0050A109 from CPE IP-address 172.20.0.10
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG com.github.freeacs.tr069.SessionData - Will load unit data
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.f.dbi.UnitQueryCrossUnittype - [      0.48 ms] SELECT u.unit_id, u.profile_id, u.unit_type_id, up.unit_type_param_id, up.value FROM unit u LEFT JOIN unit_param up ON u.unit_id = up.unit_id WHERE u.unit_id = 'IPHO0050A109' 
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.freeacs.base.db.DBAccessSession - Found unit IPHO0050A109, unittype 7259G, profile Default7259G
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG com.github.freeacs.tr069.SessionData - Found unit in database - in total 3 params (3 unit params, 0 profile params (0 overridden), 0 always read params added)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG com.github.freeacs.tr069.SessionData - Removed 3 system parameter from param-list, now contains 0 params
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] INFO  c.g.f.base.http.BasicAuthenticator - Authentication verified (CPE IP address: 172.20.0.10)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG com.github.freeacs.common.util.Cache - Key 172.20.0.10Basic SVBITzAwNTBBMTA5OnBhc3N3b3JkMTIz will be removed from Cache (explicitely - not by Cache.Cleanup.run())
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.f.t.methods.HTTPRequestProcessor - Will process method Inform (incoming request/response from CPE)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.github.freeacs.tr069.methods.INreq - Parsed INreq params, found keyroot:Device., parameterkey:, swver:C5.6.0.39
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.github.freeacs.tr069.ParameterKey - No device parameter values found, ACS parameterkey = "No data in DB"
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] DEBUG c.g.freeacs.tr069.HTTPReqResData - Adding a HTTPReqResData object to the list
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] DEBUG c.g.f.t.methods.HTTPRequestProcessor - Will process method AutonomousTransferComplete (incoming request/response from CPE)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] ERROR c.github.freeacs.tr069.Provisioning - An error ocurred: Could not process HTTP-request (from TR-069 client)
tr069_1       | com.github.freeacs.tr069.UnknownMethodException: The method AutonomousTransferComplete was not not recognized by the server.
tr069_1       |         at com.github.freeacs.tr069.methods.HTTPRequestProcessor.processRequest(HTTPRequestProcessor.java:62)
tr069_1       |         at com.github.freeacs.tr069.Provisioning.doPost(Provisioning.java:134)
tr069_1       |         at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
tr069_1       |         at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
tr069_1       |         at com.github.freeacs.common.spark.ResponseHelper.process(ResponseHelper.java:23)
tr069_1       |         at com.github.freeacs.App.lambda$null$1(App.java:74)
tr069_1       |         at spark.RouteImpl$1.handle(RouteImpl.java:72)
tr069_1       |         at spark.http.matching.Routes.execute(Routes.java:61)
tr069_1       |         at spark.http.matching.MatcherFilter.doFilter(MatcherFilter.java:134)
tr069_1       |         at spark.embeddedserver.jetty.JettyHandler.doHandle(JettyHandler.java:50)
tr069_1       |         at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1568)
tr069_1       |         at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
tr069_1       |         at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
tr069_1       |         at org.eclipse.jetty.server.Server.handle(Server.java:503)
tr069_1       |         at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364)
tr069_1       |         at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
tr069_1       |         at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
tr069_1       |         at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
tr069_1       |         at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
tr069_1       |         at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
tr069_1       |         at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
tr069_1       |         at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
tr069_1       |         at java.lang.Thread.run(Thread.java:748)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] ERROR c.github.freeacs.tr069.Provisioning - Could not process HTTP-request (from TR-069 client)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] ERROR c.github.freeacs.tr069.Provisioning - Something went wrong
tr069_1       | com.github.freeacs.tr069.exception.TR069Exception: Could not process HTTP-request (from TR-069 client)
tr069_1       |         at com.github.freeacs.tr069.methods.HTTPRequestProcessor.processRequest(HTTPRequestProcessor.java:71)
tr069_1       |         at com.github.freeacs.tr069.Provisioning.doPost(Provisioning.java:134)
tr069_1       |         at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
tr069_1       |         at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
tr069_1       |         at com.github.freeacs.common.spark.ResponseHelper.process(ResponseHelper.java:23)
tr069_1       |         at com.github.freeacs.App.lambda$null$1(App.java:74)
tr069_1       |         at spark.RouteImpl$1.handle(RouteImpl.java:72)
tr069_1       |         at spark.http.matching.Routes.execute(Routes.java:61)
tr069_1       |         at spark.http.matching.MatcherFilter.doFilter(MatcherFilter.java:134)
tr069_1       |         at spark.embeddedserver.jetty.JettyHandler.doHandle(JettyHandler.java:50)
tr069_1       |         at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1568)
tr069_1       |         at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
tr069_1       |         at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
tr069_1       |         at org.eclipse.jetty.server.Server.handle(Server.java:503)
tr069_1       |         at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364)
tr069_1       |         at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
tr069_1       |         at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
tr069_1       |         at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
tr069_1       |         at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
tr069_1       |         at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
tr069_1       |         at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
tr069_1       |         at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
tr069_1       |         at java.lang.Thread.run(Thread.java:748)
tr069_1       | Caused by: com.github.freeacs.tr069.UnknownMethodException: The method AutonomousTransferComplete was not not recognized by the server.
tr069_1       |         at com.github.freeacs.tr069.methods.HTTPRequestProcessor.processRequest(HTTPRequestProcessor.java:62)
tr069_1       |         ... 26 common frames omitted
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] DEBUG c.github.freeacs.tr069.Provisioning - End of session is reached, will write queued unit parameters if unit (IPHO0050A109) is not null
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] DEBUG com.github.freeacs.common.util.Cache - Key IPHO0050A109SESSION will be removed from Cache (explicitely - not by Cache.Cleanup.run())
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] DEBUG com.github.freeacs.common.util.Cache - Key node015fq3gch221uu1ged3e2cxkhfp77SESSION will be removed from Cache (explicitely - not by Cache.Cleanup.run())

The provider tell me is try to transfer something to the ONT.

jarlah commented 5 years ago

Well, its not supported or there is a bug. Now we are in feature request land. We can add simple handling of this event if possible but to really implement it, not sure when or if at all.

jarlah commented 5 years ago

But will take a brief look in spec too see what this is

jarlah commented 5 years ago

More interested in how #195 is going

penaivanalejandro commented 5 years ago

Hi... I add the URL you tell me on the ONT 7259G (UnitType)...

And now have this error in the log (All this are in docker):

tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-17837] DEBUG c.g.freeacs.tr069.HTTPReqResData - Sessionid node01tcqz6nm974yo5ptfsu92jkg676 did not return a SessionData object from cache, must create a new SessionData object
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-17837] DEBUG c.g.freeacs.tr069.HTTPReqResData - Sessionid node01tcqz6nm974yo5ptfsu92jkg676 created: 1539355446210, lastAccess:1539355446210, mxInactiveInterval:-1
tr069_1       | 2018-10-12 09:44:06 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Cache.Cleanup.run() starts
tr069_1       | Exception in thread "Cache Cleanup" java.util.ConcurrentModificationException
tr069_1       |         at java.util.Hashtable$Enumerator.next(Hashtable.java:1387)
tr069_1       |         at com.github.freeacs.common.util.Cache$Cleanup.run(Cache.java:59)
tr069_1       |         at java.lang.Thread.run(Thread.java:748)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-17837] DEBUG c.g.freeacs.tr069.HTTPReqResData - Adding a HTTPReqResData object to the list
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-17837] INFO  c.g.f.base.http.BasicAuthenticator - Send challenge to CPE, located on IP-address 172.20.0.10
tr069_1       | 2018-10-12 09:44:06 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Key node0m1urmtoag2tzueharz5abf8f70SESSION with CacheValue com.github.freeacs.common.util.CacheValue@2bf5f8c5 is to be removed
tr069_1       | 2018-10-12 09:44:06 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - CacheValue has a cleanupnotifier-class which will be executed
tr069_1       | 2018-10-12 09:44:06 [Cache Cleanup] ERROR c.g.f.base.SessionDataCacheCleanup - SessionData for null (key:node0m1urmtoag2tzueharz5abf8f70) was removed from cache after timeout - indicate a session which did not terminate correctly
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.freeacs.tr069.HTTPReqResData - Sessionid node015fq3gch221uu1ged3e2cxkhfp77 did not return a SessionData object from cache, must create a new SessionData object
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.freeacs.tr069.HTTPReqResData - Sessionid node015fq3gch221uu1ged3e2cxkhfp77 created: 1539355446285, lastAccess:1539355446285, mxInactiveInterval:-1
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.freeacs.tr069.HTTPReqResData - Adding a HTTPReqResData object to the list
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.f.base.http.BasicAuthenticator - Basic verification of CPE starts, located on IP-address 172.20.0.10
tr069_1       | 2018-10-12 09:44:06 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Cache.Cleanup.run() starts
tr069_1       | 2018-10-12 09:44:06 [Cache Cleanup] DEBUG com.github.freeacs.common.util.Cache - Cache removed 0 elements out of 0 in 0 ms.
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.f.base.http.DigestAuthenticator - Basic verification identifed unit id IPHO0050A109 from CPE IP-address 172.20.0.10
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG com.github.freeacs.tr069.SessionData - Will load unit data
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.f.dbi.UnitQueryCrossUnittype - [      0.48 ms] SELECT u.unit_id, u.profile_id, u.unit_type_id, up.unit_type_param_id, up.value FROM unit u LEFT JOIN unit_param up ON u.unit_id = up.unit_id WHERE u.unit_id = 'IPHO0050A109' 
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.freeacs.base.db.DBAccessSession - Found unit IPHO0050A109, unittype 7259G, profile Default7259G
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG com.github.freeacs.tr069.SessionData - Found unit in database - in total 3 params (3 unit params, 0 profile params (0 overridden), 0 always read params added)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG com.github.freeacs.tr069.SessionData - Removed 3 system parameter from param-list, now contains 0 params
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] INFO  c.g.f.base.http.BasicAuthenticator - Authentication verified (CPE IP address: 172.20.0.10)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG com.github.freeacs.common.util.Cache - Key 172.20.0.10Basic SVBITzAwNTBBMTA5OnBhc3N3b3JkMTIz will be removed from Cache (explicitely - not by Cache.Cleanup.run())
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.g.f.t.methods.HTTPRequestProcessor - Will process method Inform (incoming request/response from CPE)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.github.freeacs.tr069.methods.INreq - Parsed INreq params, found keyroot:Device., parameterkey:, swver:C5.6.0.39
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18235] DEBUG c.github.freeacs.tr069.ParameterKey - No device parameter values found, ACS parameterkey = "No data in DB"
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] DEBUG c.g.freeacs.tr069.HTTPReqResData - Adding a HTTPReqResData object to the list
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] DEBUG c.g.f.t.methods.HTTPRequestProcessor - Will process method AutonomousTransferComplete (incoming request/response from CPE)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] ERROR c.github.freeacs.tr069.Provisioning - An error ocurred: Could not process HTTP-request (from TR-069 client)
tr069_1       | com.github.freeacs.tr069.UnknownMethodException: The method AutonomousTransferComplete was not not recognized by the server.
tr069_1       |         at com.github.freeacs.tr069.methods.HTTPRequestProcessor.processRequest(HTTPRequestProcessor.java:62)
tr069_1       |         at com.github.freeacs.tr069.Provisioning.doPost(Provisioning.java:134)
tr069_1       |         at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
tr069_1       |         at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
tr069_1       |         at com.github.freeacs.common.spark.ResponseHelper.process(ResponseHelper.java:23)
tr069_1       |         at com.github.freeacs.App.lambda$null$1(App.java:74)
tr069_1       |         at spark.RouteImpl$1.handle(RouteImpl.java:72)
tr069_1       |         at spark.http.matching.Routes.execute(Routes.java:61)
tr069_1       |         at spark.http.matching.MatcherFilter.doFilter(MatcherFilter.java:134)
tr069_1       |         at spark.embeddedserver.jetty.JettyHandler.doHandle(JettyHandler.java:50)
tr069_1       |         at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1568)
tr069_1       |         at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
tr069_1       |         at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
tr069_1       |         at org.eclipse.jetty.server.Server.handle(Server.java:503)
tr069_1       |         at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364)
tr069_1       |         at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
tr069_1       |         at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
tr069_1       |         at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
tr069_1       |         at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
tr069_1       |         at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
tr069_1       |         at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
tr069_1       |         at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
tr069_1       |         at java.lang.Thread.run(Thread.java:748)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] ERROR c.github.freeacs.tr069.Provisioning - Could not process HTTP-request (from TR-069 client)
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] ERROR c.github.freeacs.tr069.Provisioning - Something went wrong
tr069_1       | com.github.freeacs.tr069.exception.TR069Exception: Could not process HTTP-request (from TR-069 client)
tr069_1       |         at com.github.freeacs.tr069.methods.HTTPRequestProcessor.processRequest(HTTPRequestProcessor.java:71)
tr069_1       |         at com.github.freeacs.tr069.Provisioning.doPost(Provisioning.java:134)
tr069_1       |         at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
tr069_1       |         at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
tr069_1       |         at com.github.freeacs.common.spark.ResponseHelper.process(ResponseHelper.java:23)
tr069_1       |         at com.github.freeacs.App.lambda$null$1(App.java:74)
tr069_1       |         at spark.RouteImpl$1.handle(RouteImpl.java:72)
tr069_1       |         at spark.http.matching.Routes.execute(Routes.java:61)
tr069_1       |         at spark.http.matching.MatcherFilter.doFilter(MatcherFilter.java:134)
tr069_1       |         at spark.embeddedserver.jetty.JettyHandler.doHandle(JettyHandler.java:50)
tr069_1       |         at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1568)
tr069_1       |         at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
tr069_1       |         at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
tr069_1       |         at org.eclipse.jetty.server.Server.handle(Server.java:503)
tr069_1       |         at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364)
tr069_1       |         at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
tr069_1       |         at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305)
tr069_1       |         at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
tr069_1       |         at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
tr069_1       |         at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
tr069_1       |         at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
tr069_1       |         at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765)
tr069_1       |         at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683)
tr069_1       |         at java.lang.Thread.run(Thread.java:748)
tr069_1       | Caused by: com.github.freeacs.tr069.UnknownMethodException: The method AutonomousTransferComplete was not not recognized by the server.
tr069_1       |         at com.github.freeacs.tr069.methods.HTTPRequestProcessor.processRequest(HTTPRequestProcessor.java:62)
tr069_1       |         ... 26 common frames omitted
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] DEBUG c.github.freeacs.tr069.Provisioning - End of session is reached, will write queued unit parameters if unit (IPHO0050A109) is not null
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] DEBUG com.github.freeacs.common.util.Cache - Key IPHO0050A109SESSION will be removed from Cache (explicitely - not by Cache.Cleanup.run())
tr069_1       | 2018-10-12 09:44:06 [qtp2044571687-18454] DEBUG com.github.freeacs.common.util.Cache - Key node015fq3gch221uu1ged3e2cxkhfp77SESSION will be removed from Cache (explicitely - not by Cache.Cleanup.run())

The provider tell me is try to transfer something to the ONT.

Sorry this comment was for the issue #197

I am already installing Free ACS again from the "install.sh" script, finishing the tests by entering the shell and registering the parameter.

I confirm you in a moment.

jarlah commented 5 years ago

Thinking if its possible to autocreate both params automatically. They do no harm.

jarlah commented 5 years ago

Maybe as an option in the gui. Select cwmp version or keyroot or something

jarlah commented 5 years ago

i will add AutonomousTransferComplete, but will respond with AutonomousTransferCompleteResponse disregarding the content atm

jarlah commented 5 years ago

closing this issue, since its too vague. And its been fixed. I have added AutonomousTransferComplete. Please open a new issue with the remainder issues.