unit tests for 'test_dbW_functionality.R' fail on appveyor but not on travis

[dschlaep]

Commit: c648a10
Output from travis:

* checking tests ...
  Running "testthat.R" [11s/11s]
 OK
* checking PDF version of manual ... OK
* DONE

Status: 5 WARNINGs

Output from appveyor:

Running the tests in 'tests/testthat.R' failed.
Last 13 lines of output:
         conn = conn)
  16: initialize(value, ...)
  17: initialize(value, ...)
  18: rsqlite_send_query(conn@ptr, statement)
  
  testthat results ================================================================
  OK: 107 SKIPPED: 0 FAILED: 5
  1. Failure: dbW creation (@test_dbW_functionality.R#75) 
  2. Failure: dbW creation (@test_dbW_functionality.R#80) 
  3. Error: dbW creation (@test_dbW_functionality.R#89) 
  4. Error: dbW site/scenario tables manipulation (@test_dbW_functionality.R#111) 
  5. Error: dbW weather data manipulation (@test_dbW_functionality.R#158) 
  
  Error: testthat unit tests failed
  Execution halted
* DONE
Status: 1 ERROR, 4 WARNINGs, 1 NOTE

[dschlaep]

@Zachary-Kramer it would be great if you could take a look at this. I am trying to get 'rSOILWAT2' to compile on Windows OS for Rachel. I don't have access to a Windows machine which makes this type of issues hard to track down. It would be great if you could tell me whether this repeats on your Windows installation or not, e.g., by running devtools::test(), and share the detailed test report with me. Thanks!

[dschlaep]

Same problem on r-hub for 'Windows Server 2008 R2 SP1, R-patched, 32/64 bit':

1483#> Running the tests in 'tests/testthat.R' failed.
1484#> Last 13 lines of output:
1485#> conn = conn)
1486#> 16: initialize(value, ...)
1487#> 17: initialize(value, ...)
1488#> 18: rsqlite_send_query(conn@ptr, statement)
1489#>
1490#> testthat results ================================================================
1491#> OK: 107 SKIPPED: 0 FAILED: 5
1492#> 1. Failure: dbW creation (@test_dbW_functionality.R#75)
1493#> 2. Failure: dbW creation (@test_dbW_functionality.R#80)
1494#> 3. Error: dbW creation (@test_dbW_functionality.R#89)
1495#> 4. Error: dbW site/scenario tables manipulation (@test_dbW_functionality.R#111)
1496#> 5. Error: dbW weather data manipulation (@test_dbW_functionality.R#158)
1497#>
1498#> Error: testthat unit tests failed
1499#> Execution halted

[Zachary-Kramer]

rSOILWAT2 compilation/loading works with R CMD INSTALL rSOILWAT2 --no-multiarch

rSOILWAT2 loading fails with R CMD INSTALL rSOILWAT2:

* installing to library 'D:/r-3.3.1/library'
* installing *source* package 'rSOILWAT2' ...
** libs

*** arch - i386
make: Nothing to be done for `all'.
installing to D:/r-3.3.1/library/rSOILWAT2/libs/i386

*** arch - x64
c:/Rtools/mingw_64/bin/gcc -shared -s -static-libgcc -o rSOILWAT2.dll tmp.def SW_Carbon.o SW_Control.o SW_Files.o SW_Flow.o SW_Flow_lib.o SW_Main.o SW_Main_Function.o SW_Markov.o SW_Model.o SW_Output.o SW_R_init.o SW_R_lib.o SW_Site.o SW_Sky.o SW_SoilWater.o SW_VegEstab.o SW_VegProd.o SW_Weather.o Times.o filefuncs.o generic.o mymemory.o rands.o -Ld:/Compiler/gcc-4.9.3/local330/lib/x64 -Ld:/Compiler/gcc-4.9.3/local330/lib -LD:/r-3.3.1/bin/x64 -lR
installing to D:/r-3.3.1/library/rSOILWAT2/libs/x64
** R
** data
*** moving datasets to lazyload DB
** inst
** byte-compile and prepare package for lazy loading
** help
*** installing help indices
** building package indices
** testing if installed package can be loaded
*** arch - i386
Error in inDL(x, as.logical(local), as.logical(now), ...) :
  unable to load shared object 'D:/r-3.3.1/library/rSOILWAT2/libs/i386/rSOILWAT2.dll':
  LoadLibrary failure:  %1 is not a valid Win32 application.

Error: loading failed
Execution halted
*** arch - x64
ERROR: loading failed for 'i386'
* removing 'D:/r-3.3.1/library/rSOILWAT2'
* restoring previous 'D:/r-3.3.1/library/rSOILWAT2'

testthat output:

Loading rSOILWAT2
Package "rSOILWAT2" v1.3.4 (2017-07-20) attached/loaded.
Daily weather database version 3.1.1
Testing rSOILWAT2
rSOILWAT2 weather database: ..............12.....345..
rSOILWAT2 annual aggregation: ....................................................
rSOILWAT2 segfault: .
rSOILWAT2 soil temperature instability: ................................

Failed --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
1. Failure: dbW creation (@test_dbW_functionality.R#75) -------------------------------------------------------------------------------------------------------------------------------------------------
`messages` does not match "because of errors in the table data".
Actual value: "'dbW_createDatabase': cannot create a new database because the file "file1a14168e6560.sqlite3" does already exist.\n"


2. Failure: dbW creation (@test_dbW_functionality.R#80) -------------------------------------------------------------------------------------------------------------------------------------------------
dbW_createDatabase(...) isn't true.


3. Error: dbW creation (@test_dbW_functionality.R#89) ---------------------------------------------------------------------------------------------------------------------------------------------------
no such table: Meta
1: expect_equal(dbW_version(), numeric_version(rSW2_glovars$dbW_version)) at C:\GIT\rSOILWAT2/tests/testthat/test_dbW_functionality.R:89
2: compare(object, expected, ...)
3: dbW_version()
4: numeric_version(as.character(DBI::dbGetQuery(rSW2_glovars$con, sql)[1, 1])) at C:\GIT\rSOILWAT2/R/swFunctions.R:37
5: .make_numeric_version(x, strict, .standard_regexps()$valid_numeric_version)
6: DBI::dbGetQuery(rSW2_glovars$con, sql)
7: DBI::dbGetQuery(rSW2_glovars$con, sql)
8: .local(conn, statement, ...)
9: dbSendQuery(conn, statement, ...)
10: dbSendQuery(conn, statement, ...)
11: .local(conn, statement, ...)
12: new("SQLiteResult", sql = statement, ptr = rsqlite_send_query(conn@ptr, statement), conn = conn)
13: initialize(value, ...)
14: initialize(value, ...)
15: rsqlite_send_query(conn@ptr, statement)

4. Error: dbW site/scenario tables manipulation (@test_dbW_functionality.R#111) -------------------------------------------------------------------------------------------------------------------------
no such table: Sites
1: dbW_getSiteId(lat = site_data1[k, "Latitude"], long = site_data1[k, "Longitude"]) at C:\GIT\rSOILWAT2/tests/testthat/test_dbW_functionality.R:111
2: DBI::dbGetQuery(rSW2_glovars$con, sql, params = list(lat = lat, long = long)) at C:\GIT\rSOILWAT2/R/swFunctions.R:153
3: DBI::dbGetQuery(rSW2_glovars$con, sql, params = list(lat = lat, long = long))
4: .local(conn, statement, ...)
5: dbSendQuery(conn, statement, ...)
6: dbSendQuery(conn, statement, ...)
7: .local(conn, statement, ...)
8: new("SQLiteResult", sql = statement, ptr = rsqlite_send_query(conn@ptr, statement), conn = conn)
9: initialize(value, ...)
10: initialize(value, ...)
11: rsqlite_send_query(conn@ptr, statement)

5. Error: dbW weather data manipulation (@test_dbW_functionality.R#158) ---------------------------------------------------------------------------------------------------------------------------------
no such table: Sites
1: expect_true(dbW_addWeatherData(Site_id = 1, weatherData = sw_weather[[1]], Scenario = scenarios[1])) at C:\GIT\rSOILWAT2/tests/testthat/test_dbW_functionality.R:158
2: expect(identical(as.vector(object), TRUE), sprintf("%s isn't true.", lab), info = info)
3: as.expectation(exp, ..., srcref = srcref)
4: identical(as.vector(object), TRUE)
5: as.vector(object)
6: dbW_addWeatherData(Site_id = 1, weatherData = sw_weather[[1]], Scenario = scenarios[1])
7: dbW_getIDs(site_id = Site_id, site_label = Label, long = long, lat = lat, scenario = Scenario, scenario_id = Scenario_id, add_if_missing = TRUE, ignore.case = ignore.case, verbose = verbose) at C:\GIT\rSOILWAT2/R/swFunctions.R:554
8: dbW_has_siteIDs(res[["site_id"]]) at C:\GIT\rSOILWAT2/R/swFunctions.R:207
9: DBI::dbGetQuery(rSW2_glovars$con, sql, params = list(x = Site_ids)) at C:\GIT\rSOILWAT2/R/swFunctions.R:79
10: DBI::dbGetQuery(rSW2_glovars$con, sql, params = list(x = Site_ids))
11: .local(conn, statement, ...)
12: dbSendQuery(conn, statement, ...)
13: dbSendQuery(conn, statement, ...)
14: .local(conn, statement, ...)
15: new("SQLiteResult", sql = statement, ptr = rsqlite_send_query(conn@ptr, statement), conn = conn)
16: initialize(value, ...)
17: initialize(value, ...)
18: rsqlite_send_query(conn@ptr, statement)

DONE ====================================================================================================================================================================================================

Is there more information I can provide? Has Rachel tried the --no-multiarch option?

[dschlaep]

Many thanks for the quick response!

Since arch i386 has make: Nothing to be done for 'all'. indicating that the INSTALL uses previously compiled .o and .dll, could you please test with a preclean (and a clean so that they get deleted between building the different archs):
R CMD INSTALL rSOILWAT2 --preclean --clean

Did you test with commit c648a10 from the master branch? This commit is more rigorous in deleting the temporary test objects between the different unit tests.

She cannot compile on her computer. I have asked that she updates the R version and installs the corresponding Rtools. Remote problem-solving on an OS that I don't understand is hard -- hence, the new binary package section in the READMEs.

[Zachary-Kramer]

Good catch, compiling and loading rSOILWAT2 worked with R CMD INSTALL rSOILWAT2 --preclean --clean. I am on the latest commit of rSOILWAT2. I believe before I had left over objects from my CO2 branch. Regardless, the test output is the same.

Rachel should also make sure she has up to date packages. Before running test(), I had a couple out-of-date ones, like RSQLite.

[dschlaep]

Rachel's problem has been solved. The problem was that the default R package build from appveyor was for a 32-bit R and she uses 64-bit. I fixed that with a matrix build over both i386 and x64 with commit DrylandEcology/rSFSW2@dd95342.

[dschlaep]

The problem underlying this issue appears to be that the unit testing code 'test_dbW_functionality' and the function dbW_createDatabase cannot delete the file fdbWeather once created on appveyor.

> test_check("rSOILWAT2")
[1] "'fdbWeather' should not exists, but it does - so we delete it"
[1] "'fdbWeather' should not exists because we just attempted to delete \"C:/Users/appveyor/AppData/Local/Temp/1\\RtmpS2A84T\\file52875451d9c.sqlite3\""
1. Failure: dbW creation (@test_dbW_functionality.R#79) ------------------------
`messages` does not match "errors in the table data".
Actual value: "'dbW_createDatabase': cannot create a new database because the file "file52875451d9c.sqlite3" does already exist.\n"

The unit test code defines this file with R base commands fdbWeather <- tempfile(fileext = ".sqlite3") and the function dbW_createDatabase applies normalizePath to the directory part of it dbFilePath <- file.path(normalizePath(dirname(dbFilePath)), basename(dbFilePath)). Both attempt to delete such files with the base R command unlink, but apparently fail.

@Zachary-Kramer, do you have any clue what is going on here: why can the code create this file, but not delete it?

[Zachary-Kramer]

Is Appveyor an admin? You could try a force delete just to be safe. Also, the file path is a bit weird. The change from / to \\ is fine, but it escapes with a \, which suggests that the original file path was C:/Users/appveyor/AppData/Local/Temp/1\\RtmpS2A84T\\file52875451d9c.sqlite3\\. If that's the case, it's treating the database as a directory and won't delete it. I would investigate that before any serious debugging.

[dschlaep]

I attempted with unlink(dbFilePath, force = TRUE) but it didn't change the outcome.

I am not sure about the permissions on appveyor, but it is suggested that the appveyor build agent is a member of admin. However, there seems to be issues with proper inheritance of permissions... at least based on some comments on this discussion thread about permission issues on appveyor: http://help.appveyor.com/discussions/problems/938-getting-permission-denied-errors-when-trying-to-make-a-temp-directory
Looks like we are not the only ones with such an issue!

Thanks for the tip that Windows OS may believe that dbFilePath is a directory and not a file. Though that would be weird because R is supposed to handle that internally particularly when filename is created by tempfile. Maybe we need to call unlink(dbFilePath, recursive = TRUE)?

[dschlaep]

unlink(dbFilePath, recursive = TRUE) didn't help.

The unquoted path is (I used shQuote() before):

[1] "'fdbWeather' should not exists because we just attempted to delete C:/Users/appveyor/AppData/Local/Temp/1\Rtmp4Kbzta\filebdc397c4c2d.sqlite3"

So Windows OS can provide write but not delete permissions as a default to a user of the admin group?

[Zachary-Kramer]

Okay, the unquoted path makes sense and shouldn't be an issue. I'm unsure of Window's write permissions to the temp directory, though you have to be an admin to delete. Though if Appveyor lacked permission I would assume that an obvious "Access is denied" error would show up in R, like it does when trying to modify an open CSV. To be 100% certain, you could replace tempfile with a hard-coded path to a standard folder (e.g. C:/test) to confirm that it isn't a permissions issue.

Do you know if it's possible that the database is in use? Unlink() will remove some locked files, like text files, but not .sqlite3 files. It'll just silently fail.

[dschlaep]

I tested with a hard-coded path to C:/test, but same failure.

I added two unit tests: one to write a NA value to dbFilePath and one to remove the created file dbFilePath. Both tests pass.

I now also make sure that dbW_createDatabase has disconnected RSQLite from the dbFilePath database before attempting to delete it with unlink - but this still fails on appveyor -- apparently the Windows file system still believes that dbFilePath is not free and its or R's unlink silently fails.

[Zachary-Kramer]

Hmm, that rules out all the simple reasons. You should check the return value of unlink to see if it thinks it failed, or try file.remove with showWarnings set to true. I can look a little more into it tonight.

[dschlaep]

Apparently, it is tricky for many to make sure that sqlite3 releases indeed all resources/locks from a database file on Windows OS according to this and this stackoverflow discussions. One suggestion is to do a garbage collection.

btw, file.remove does not have an argument showWarnings unlike file.create and dir.create

[dschlaep]

I added a gc garbage collection after dbDisconnect and before both unlink and file.remove. Nothing seems to help.

@Zachary-Kramer I would greatly appreciate if you could look into this issue #43 and the branch addressing it bugfix_44 and its pull-request #45. Sorry, I know - bad name -- I created this branch to address issue #44 and then got sidetracked with issue #43 and forgot to move to a new dedicated branch...

[dschlaep]

Undo 05ee7a3 once this is solved.

[Zachary-Kramer]

Noted. I do not have any allocated time to debug this, so if it is urgent it should be assigned to someone else. SSURGO and high priority CO2 features have a higher importance at the moment, and I only work 10 hours a week. If it's not urgent, I can get to it in a couple weeks or so.

[dschlaep]

@Zachary-Kramer Please take a look into this when you get time to do so. It doesn't seem to be urgent: I haven't heard from Rachel that she has problems with rSOILWAT2 on Windows OS so far.

[dschlaep]

This issue is now showing up on Github Actions workflow on only Windows 64 (not 32) (commit 9ea46fe) https://github.com/DrylandEcology/rSOILWAT2/runs/3557590269?check_suite_focus=true

== Failed ======================================================================
-- 1. Failure (test_dbW_functionality.R:109:3): dbW creation -------------------
`unlink_forcefully(fdbWeather, info = "2nd")` produced unexpected messages.
Expected match: sucessfully deleted
Actual values:
* 2nd: file C:\Users\RUNNER~1\AppData\Local\Temp\RtmpS4Y9ef/working_dir\RtmpkljqsD\file9182d4351d5.sqlite3 should not exists, but it does - so we delete it.

* 2nd: file C:\Users\RUNNER~1\AppData\Local\Temp\RtmpS4Y9ef/working_dir\RtmpkljqsD\file9182d4351d5.sqlite3 should not exists because we just attempted to delete it.


-- 2. Failure (test_dbW_functionality.R:111:3): dbW creation -------------------
`dbW_createDatabase(fdbWeather, verbose = TRUE)` produced unexpected messages.
Expected match: errors in the table data
Actual values:
* 'dbW_createDatabase': cannot create a new database because the file "file9182d4351d5.sqlite3" does already exist.


-- 3. Failure (test_dbW_functionality.R:119:3): dbW creation -------------------
`unlink_forcefully(fdbWeather, info = "3rd")` produced unexpected messages.
Expected match: sucessfully deleted
Actual values:
* 3rd: file C:\Users\RUNNER~1\AppData\Local\Temp\RtmpS4Y9ef/working_dir\RtmpkljqsD\file9182d4351d5.sqlite3 should not exists, but it does - so we delete it.

* 3rd: file C:\Users\RUNNER~1\AppData\Local\Temp\RtmpS4Y9ef/working_dir\RtmpkljqsD\file9182d4351d5.sqlite3 should not exists because we just attempted to delete it.


-- 4. Failure (test_dbW_functionality.R:123:3): dbW creation -------------------
`unlink_forcefully(fdbWeather, info = "4th")` produced unexpected messages.
Expected match: sucessfully deleted
Actual values:
* 4th: file C:\Users\RUNNER~1\AppData\Local\Temp\RtmpS4Y9ef/working_dir\RtmpkljqsD\file9182d4351d5.sqlite3 should not exists, but it does - so we delete it.

* 4th: file C:\Users\RUNNER~1\AppData\Local\Temp\RtmpS4Y9ef/working_dir\RtmpkljqsD\file9182d4351d5.sqlite3 should not exists because we just attempted to delete it.


-- 5. Failure (test_dbW_functionality.R:125:3): dbW creation -------------------
`dbW_createDatabase(...)` produced unexpected messages.
Expected match: errors in the table data
Actual values:
* 'dbW_createDatabase': cannot create a new database because the file "file9182d4351d5.sqlite3" does already exist.


-- 6. Failure (test_dbW_functionality.R:130:3): dbW creation -------------------
dbW_createDatabase(...) is not TRUE

`actual`:   FALSE
`expected`: TRUE 

-- 7. Error (test_dbW_functionality.R:139:3): dbW creation ---------------------
Error: Error: no such table: Meta
Backtrace:
  1. testthat::expect_equal(dbW_version(), numeric_version(rSW2_glovars$dbW_version)) test_dbW_functionality.R:139:2
  4. rSOILWAT2::dbW_version()
  8. DBI::dbGetQuery(rSW2_glovars$con, sql)
  9. DBI:::.local(conn, statement, ...)
 11. RSQLite::dbSendQuery(conn, statement, ...)
 12. RSQLite:::.local(conn, statement, ...)
 16. RSQLite:::result_create(conn@ptr, statement)

-- 8. Error (test_dbW_functionality.R:165:3): dbW site/scenario tables manipulat
Error: Error: no such table: Sites
Backtrace:
 1. rSOILWAT2::dbW_getSiteId(...) test_dbW_functionality.R:165:2
 3. DBI::dbSendQuery(rSW2_glovars$con, sql)
 4. RSQLite:::.local(conn, statement, ...)
 8. RSQLite:::result_create(conn@ptr, statement)

-- 9. Error (test_dbW_functionality.R:342:3): dbW weather data manipulation ----
Error: Error: no such table: Sites
Backtrace:
  1. testthat::expect_true(...) test_dbW_functionality.R:342:2
  4. rSOILWAT2::dbW_addWeatherData(...)
  5. rSOILWAT2::dbW_getIDs(...)
  6. rSOILWAT2::dbW_has_siteIDs(res[["site_id"]])
  8. DBI::dbGetQuery(rSW2_glovars$con, sql, params = list(x = Site_ids))
  9. DBI:::.local(conn, statement, ...)
 11. RSQLite::dbSendQuery(conn, statement, ...)
 12. RSQLite:::.local(conn, statement, ...)
 16. RSQLite:::result_create(conn@ptr, statement)